Thanks Greg and Molly for your comments, they were helpful. Indeed my first comment was wrong. I managed to reproduce exactly the profile shared in comment 1. It happens when a DLL that is registered with `SetWindowsHookExW` for `WH_GETMESSAGE` gets blocked by our blocklist. I managed to reproduce by registering my own DLL and blocking it in `about:third-party`, then I realized that the story is a little bit different for `pmls64.dll`... (In reply to Greg Stoll from comment #2) > We have seen issues like this before when we add a DLL that gets loaded by a window hook to the DLL blocklist, and our advice is...[don't block those DLLs](https://firefox-source-docs.mozilla.org/widget/windows/blocklist.html#cases-where-we-should-not-block-a-module), which isn't helpful in this case since we're not doing the blocking. ... In fact [we **are** doing the blocking](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/WindowsDllBlocklistDefs.in#163)! First let me clarify what we see in the profile now that I understand it better. For a start, the raw addresses ending in 74 and b4 without symbols correspond to the following stacks: ``` # Child-SP RetAddr Call Site 00 0000001f`e6ffdb78 00007ff6`2bdb03d6 0x00000216`7a8c2c74 (orig_OpenFile) 01 0000001f`e6ffdb80 00007ff6`2bdb5125 firefox!TargetNtOpenFile+0x56 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/filesystem_interception.cc @ 125] 02 0000001f`e6ffdcf0 00007ff9`3c46064c firefox!TargetNtOpenFile64+0x35 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/interceptors_64.cc @ 120] 03 0000001f`e6ffdd30 00007ff9`3c4610e0 ntdll!LdrpMapDllNtFileName+0xe8 04 0000001f`e6ffde30 00007ff9`3c460eaf ntdll!LdrpMapDllFullPath+0xe0 05 0000001f`e6ffdfc0 00007ff9`3c4788c4 ntdll!LdrpProcessWork+0x77 06 0000001f`e6ffe010 00007ff9`3c468c9c ntdll!LdrpLoadDllInternal+0x1a0 07 0000001f`e6ffe0b0 00007ff9`3c47a24a ntdll!LdrpLoadDll+0xb0 08 0000001f`e6ffe270 00007ff6`2bd98803 ntdll!LdrLoadDll+0xfa 09 (Inline Function) --------`-------- firefox!mozilla::interceptor::FuncHookCrossProcess<mozilla::interceptor::WindowsDllInterceptor<mozilla::interceptor::VMSharingPolicyUnique<mozilla::interceptor::MMPolicyOutOfProcess> >,long (*)(wchar_t *, unsigned long *, _UNICODE_STRING *, void **)>::operator()+0x19 [/builds/worker/workspace/obj-build/dist/include/nsWindowsDllInterceptor.h @ 254] 0a 0000001f`e6ffe360 00007ff9`39bbbb92 firefox!mozilla::freestanding::patched_LdrLoadDll+0x1b3 [/builds/worker/checkouts/gecko/browser/app/winlauncher/freestanding/DllBlocklist.cpp @ 360] 0b 0000001f`e6ffe440 00007ff9`3a51e067 KERNELBASE!LoadLibraryExW+0x172 0c 0000001f`e6ffe4b0 00007ff9`3c4f2c94 user32!_ClientLoadLibrary+0xa7 0d 0000001f`e6ffe650 00007ff9`39f314d4 ntdll!KiUserCallbackDispatcherContinue 0e 0000001f`e6ffe768 00007ff9`3a531bdf win32u!NtUserPeekMessage+0x14 0f 0000001f`e6ffe770 00007ff9`3a531aac user32!_PeekMessage+0x3f 10 0000001f`e6ffe7e0 00007ff8`63d37d4c user32!PeekMessageW+0x9c ... # Child-SP RetAddr Call Site 00 0000001f`e6ffdb98 00007ff6`2bdb0885 0x00000216`7a8c2cb4 (orig_QueryAttributes) 01 0000001f`e6ffdba0 00007ff9`3c47ac39 firefox!TargetNtQueryAttributesFile+0x35 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/filesystem_interception.cc @ 204] 02 0000001f`e6ffdce0 00007ff9`3c47a3f7 ntdll!LdrpGetNtPathFromDosPath+0x95 03 0000001f`e6ffddc0 00007ff9`3c461072 ntdll!LdrpResolveDllName+0x103 04 0000001f`e6ffde30 00007ff9`3c460eaf ntdll!LdrpMapDllFullPath+0x72 05 0000001f`e6ffdfc0 00007ff9`3c4788c4 ntdll!LdrpProcessWork+0x77 06 0000001f`e6ffe010 00007ff9`3c468c9c ntdll!LdrpLoadDllInternal+0x1a0 07 0000001f`e6ffe0b0 00007ff9`3c47a24a ntdll!LdrpLoadDll+0xb0 08 0000001f`e6ffe270 00007ff6`2bd98803 ntdll!LdrLoadDll+0xfa 09 (Inline Function) --------`-------- firefox!mozilla::interceptor::FuncHookCrossProcess<mozilla::interceptor::WindowsDllInterceptor<mozilla::interceptor::VMSharingPolicyUnique<mozilla::interceptor::MMPolicyOutOfProcess> >,long (*)(wchar_t *, unsigned long *, _UNICODE_STRING *, void **)>::operator()+0x19 [/builds/worker/workspace/obj-build/dist/include/nsWindowsDllInterceptor.h @ 254] 0a 0000001f`e6ffe360 00007ff9`39bbbb92 firefox!mozilla::freestanding::patched_LdrLoadDll+0x1b3 [/builds/worker/checkouts/gecko/browser/app/winlauncher/freestanding/DllBlocklist.cpp @ 360] 0b 0000001f`e6ffe440 00007ff9`3a51e067 KERNELBASE!LoadLibraryExW+0x172 0c 0000001f`e6ffe4b0 00007ff9`3c4f2c94 user32!_ClientLoadLibrary+0xa7 0d 0000001f`e6ffe650 00007ff9`39f314d4 ntdll!KiUserCallbackDispatcherContinue 0e 0000001f`e6ffe768 00007ff9`3a531bdf win32u!NtUserPeekMessage+0x14 0f 0000001f`e6ffe770 00007ff9`3a531aac user32!_PeekMessage+0x3f 10 0000001f`e6ffe7e0 00007ff8`63d37d4c user32!PeekMessageW+0x9c ... ``` Now, why do we not have full stacks for `orig_OpenFile`, `orig_QueryAttributes`, `NtClose`, `NtCreateSection`, `ZwMapViewOfSection`, `ZwQueryVirtualMemory`, `ZwUnmapViewOfSection`? Because they all happen in `LdrLoadDll`, and before calling into `LdrLoadDll` we [disable](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#37) stack walking [over concerns about the function table locks](https://searchfox.org/mozilla-central/source/mozglue/misc/StackWalk.cpp#112-115), and we [restore](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#50) it only after the call. So even though these calls seem to appear out of nowhere in the profile, they should be understood as having the same call stack as what I just shared above. When we understand that, it confirms that the process spends ~100% of its time in `nsThread::ProcessNextEvent`. In fact, we are facing an infinite cycle of events, where the code that we execute to process an event will itself generate a new (DLL load) event that needs to be processed, and again, leaving the process no time to rest. Here is how the cycle appears: - a first legitimate native event arrives; - we reach `nsThread::ProcessNextEvent` to look for an event; - that calls into `nsBaseAppShell::OnProcessNextEvent`, which calls into `PeekMessageW`; - there is an event, and `pmls64.dll` is not loaded yet, so we reach `_ClientLoadLibrary` to load `pmls64.dll` where the registered hook lives; - that calls `patched_LdrLoadDll`, which will fail to load the DLL, then will call into `DllServices::DispatchDllLoadNotification` to register a new DLL load event for the main thread, without actually posting it for the moment; - since loading the DLL failed, we handle the original event without applying the hook, then we return from `PeekMessageW`; - the next call to `nsThread::ProcessNextEvent` will reach `EnsureMainThreadTasksScheduled`, where the DLL load event will be posted with `PostMessage` as a new legitimate native event, right before going into `nsBaseAppShell::OnProcessNextEvent`, thus starting a new iteration of the cycle. Note that when we only have a cycle because of blocking. If we do not block a DLL, we avoid the cycle: - if the DLL loads successfully, further calls into `PeekMessageW` will not call into `_ClientLoadLibrary` for the same library anymore, they will call the hook directly; - if the DLL fails to load for another reason than blocking (e.g. `DllMain` returns `FALSE` on `DLL_PROCESS_ATTACH`), [we do not generate any DLL load event](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#61-66). The cycle described above exists even when the profiler is not attached.
Bug 1823412 Comment 4 Edit History
Note: The actual edited comment in the bug view page will always show the original commenter’s name and original timestamp.
Thanks Greg and Molly for your comments, they were helpful. Indeed my first comment was wrong. I managed to reproduce exactly the profile shared in the description. It happens when a DLL that is registered with `SetWindowsHookExW` for `WH_GETMESSAGE` gets blocked by our blocklist. I managed to reproduce by registering my own DLL and blocking it in `about:third-party`, then I realized that the story is a little bit different for `pmls64.dll`... (In reply to Greg Stoll from comment #2) > We have seen issues like this before when we add a DLL that gets loaded by a window hook to the DLL blocklist, and our advice is...[don't block those DLLs](https://firefox-source-docs.mozilla.org/widget/windows/blocklist.html#cases-where-we-should-not-block-a-module), which isn't helpful in this case since we're not doing the blocking. ... In fact [we **are** doing the blocking](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/WindowsDllBlocklistDefs.in#163)! First let me clarify what we see in the profile now that I understand it better. For a start, the raw addresses ending in 74 and b4 without symbols correspond to the following stacks: ``` # Child-SP RetAddr Call Site 00 0000001f`e6ffdb78 00007ff6`2bdb03d6 0x00000216`7a8c2c74 (orig_OpenFile) 01 0000001f`e6ffdb80 00007ff6`2bdb5125 firefox!TargetNtOpenFile+0x56 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/filesystem_interception.cc @ 125] 02 0000001f`e6ffdcf0 00007ff9`3c46064c firefox!TargetNtOpenFile64+0x35 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/interceptors_64.cc @ 120] 03 0000001f`e6ffdd30 00007ff9`3c4610e0 ntdll!LdrpMapDllNtFileName+0xe8 04 0000001f`e6ffde30 00007ff9`3c460eaf ntdll!LdrpMapDllFullPath+0xe0 05 0000001f`e6ffdfc0 00007ff9`3c4788c4 ntdll!LdrpProcessWork+0x77 06 0000001f`e6ffe010 00007ff9`3c468c9c ntdll!LdrpLoadDllInternal+0x1a0 07 0000001f`e6ffe0b0 00007ff9`3c47a24a ntdll!LdrpLoadDll+0xb0 08 0000001f`e6ffe270 00007ff6`2bd98803 ntdll!LdrLoadDll+0xfa 09 (Inline Function) --------`-------- firefox!mozilla::interceptor::FuncHookCrossProcess<mozilla::interceptor::WindowsDllInterceptor<mozilla::interceptor::VMSharingPolicyUnique<mozilla::interceptor::MMPolicyOutOfProcess> >,long (*)(wchar_t *, unsigned long *, _UNICODE_STRING *, void **)>::operator()+0x19 [/builds/worker/workspace/obj-build/dist/include/nsWindowsDllInterceptor.h @ 254] 0a 0000001f`e6ffe360 00007ff9`39bbbb92 firefox!mozilla::freestanding::patched_LdrLoadDll+0x1b3 [/builds/worker/checkouts/gecko/browser/app/winlauncher/freestanding/DllBlocklist.cpp @ 360] 0b 0000001f`e6ffe440 00007ff9`3a51e067 KERNELBASE!LoadLibraryExW+0x172 0c 0000001f`e6ffe4b0 00007ff9`3c4f2c94 user32!_ClientLoadLibrary+0xa7 0d 0000001f`e6ffe650 00007ff9`39f314d4 ntdll!KiUserCallbackDispatcherContinue 0e 0000001f`e6ffe768 00007ff9`3a531bdf win32u!NtUserPeekMessage+0x14 0f 0000001f`e6ffe770 00007ff9`3a531aac user32!_PeekMessage+0x3f 10 0000001f`e6ffe7e0 00007ff8`63d37d4c user32!PeekMessageW+0x9c ... # Child-SP RetAddr Call Site 00 0000001f`e6ffdb98 00007ff6`2bdb0885 0x00000216`7a8c2cb4 (orig_QueryAttributes) 01 0000001f`e6ffdba0 00007ff9`3c47ac39 firefox!TargetNtQueryAttributesFile+0x35 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/filesystem_interception.cc @ 204] 02 0000001f`e6ffdce0 00007ff9`3c47a3f7 ntdll!LdrpGetNtPathFromDosPath+0x95 03 0000001f`e6ffddc0 00007ff9`3c461072 ntdll!LdrpResolveDllName+0x103 04 0000001f`e6ffde30 00007ff9`3c460eaf ntdll!LdrpMapDllFullPath+0x72 05 0000001f`e6ffdfc0 00007ff9`3c4788c4 ntdll!LdrpProcessWork+0x77 06 0000001f`e6ffe010 00007ff9`3c468c9c ntdll!LdrpLoadDllInternal+0x1a0 07 0000001f`e6ffe0b0 00007ff9`3c47a24a ntdll!LdrpLoadDll+0xb0 08 0000001f`e6ffe270 00007ff6`2bd98803 ntdll!LdrLoadDll+0xfa 09 (Inline Function) --------`-------- firefox!mozilla::interceptor::FuncHookCrossProcess<mozilla::interceptor::WindowsDllInterceptor<mozilla::interceptor::VMSharingPolicyUnique<mozilla::interceptor::MMPolicyOutOfProcess> >,long (*)(wchar_t *, unsigned long *, _UNICODE_STRING *, void **)>::operator()+0x19 [/builds/worker/workspace/obj-build/dist/include/nsWindowsDllInterceptor.h @ 254] 0a 0000001f`e6ffe360 00007ff9`39bbbb92 firefox!mozilla::freestanding::patched_LdrLoadDll+0x1b3 [/builds/worker/checkouts/gecko/browser/app/winlauncher/freestanding/DllBlocklist.cpp @ 360] 0b 0000001f`e6ffe440 00007ff9`3a51e067 KERNELBASE!LoadLibraryExW+0x172 0c 0000001f`e6ffe4b0 00007ff9`3c4f2c94 user32!_ClientLoadLibrary+0xa7 0d 0000001f`e6ffe650 00007ff9`39f314d4 ntdll!KiUserCallbackDispatcherContinue 0e 0000001f`e6ffe768 00007ff9`3a531bdf win32u!NtUserPeekMessage+0x14 0f 0000001f`e6ffe770 00007ff9`3a531aac user32!_PeekMessage+0x3f 10 0000001f`e6ffe7e0 00007ff8`63d37d4c user32!PeekMessageW+0x9c ... ``` Now, why do we not have full stacks for `orig_OpenFile`, `orig_QueryAttributes`, `NtClose`, `NtCreateSection`, `ZwMapViewOfSection`, `ZwQueryVirtualMemory`, `ZwUnmapViewOfSection`? Because they all happen in `LdrLoadDll`, and before calling into `LdrLoadDll` we [disable](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#37) stack walking [over concerns about the function table locks](https://searchfox.org/mozilla-central/source/mozglue/misc/StackWalk.cpp#112-115), and we [restore](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#50) it only after the call. So even though these calls seem to appear out of nowhere in the profile, they should be understood as having the same call stack as what I just shared above. When we understand that, it confirms that the process spends ~100% of its time in `nsThread::ProcessNextEvent`. In fact, we are facing an infinite cycle of events, where the code that we execute to process an event will itself generate a new (DLL load) event that needs to be processed, and again, leaving the process no time to rest. Here is how the cycle appears: - a first legitimate native event arrives; - we reach `nsThread::ProcessNextEvent` to look for an event; - that calls into `nsBaseAppShell::OnProcessNextEvent`, which calls into `PeekMessageW`; - there is an event, and `pmls64.dll` is not loaded yet, so we reach `_ClientLoadLibrary` to load `pmls64.dll` where the registered hook lives; - that calls `patched_LdrLoadDll`, which will fail to load the DLL, then will call into `DllServices::DispatchDllLoadNotification` to register a new DLL load event for the main thread, without actually posting it for the moment; - since loading the DLL failed, we handle the original event without applying the hook, then we return from `PeekMessageW`; - the next call to `nsThread::ProcessNextEvent` will reach `EnsureMainThreadTasksScheduled`, where the DLL load event will be posted with `PostMessage` as a new legitimate native event, right before going into `nsBaseAppShell::OnProcessNextEvent`, thus starting a new iteration of the cycle. Note that when we only have a cycle because of blocking. If we do not block a DLL, we avoid the cycle: - if the DLL loads successfully, further calls into `PeekMessageW` will not call into `_ClientLoadLibrary` for the same library anymore, they will call the hook directly; - if the DLL fails to load for another reason than blocking (e.g. `DllMain` returns `FALSE` on `DLL_PROCESS_ATTACH`), [we do not generate any DLL load event](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#61-66). The cycle described above exists even when the profiler is not attached.
Thanks Greg and Molly for your comments, they were helpful. Indeed my first comment was wrong. I managed to reproduce exactly the profile shared in the description. It happens when a DLL that is registered with `SetWindowsHookExW` for `WH_GETMESSAGE` gets blocked by our blocklist. I managed to reproduce the profile by registering my own DLL and blocking it in `about:third-party`, then I realized that the story is a little bit different for `pmls64.dll`... (In reply to Greg Stoll from comment #2) > We have seen issues like this before when we add a DLL that gets loaded by a window hook to the DLL blocklist, and our advice is...[don't block those DLLs](https://firefox-source-docs.mozilla.org/widget/windows/blocklist.html#cases-where-we-should-not-block-a-module), which isn't helpful in this case since we're not doing the blocking. ... In fact [we **are** doing the blocking](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/WindowsDllBlocklistDefs.in#163)! First let me clarify what we see in the profile now that I understand it better. For a start, the raw addresses ending in 74 and b4 without symbols correspond to the following stacks: ``` # Child-SP RetAddr Call Site 00 0000001f`e6ffdb78 00007ff6`2bdb03d6 0x00000216`7a8c2c74 (orig_OpenFile) 01 0000001f`e6ffdb80 00007ff6`2bdb5125 firefox!TargetNtOpenFile+0x56 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/filesystem_interception.cc @ 125] 02 0000001f`e6ffdcf0 00007ff9`3c46064c firefox!TargetNtOpenFile64+0x35 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/interceptors_64.cc @ 120] 03 0000001f`e6ffdd30 00007ff9`3c4610e0 ntdll!LdrpMapDllNtFileName+0xe8 04 0000001f`e6ffde30 00007ff9`3c460eaf ntdll!LdrpMapDllFullPath+0xe0 05 0000001f`e6ffdfc0 00007ff9`3c4788c4 ntdll!LdrpProcessWork+0x77 06 0000001f`e6ffe010 00007ff9`3c468c9c ntdll!LdrpLoadDllInternal+0x1a0 07 0000001f`e6ffe0b0 00007ff9`3c47a24a ntdll!LdrpLoadDll+0xb0 08 0000001f`e6ffe270 00007ff6`2bd98803 ntdll!LdrLoadDll+0xfa 09 (Inline Function) --------`-------- firefox!mozilla::interceptor::FuncHookCrossProcess<mozilla::interceptor::WindowsDllInterceptor<mozilla::interceptor::VMSharingPolicyUnique<mozilla::interceptor::MMPolicyOutOfProcess> >,long (*)(wchar_t *, unsigned long *, _UNICODE_STRING *, void **)>::operator()+0x19 [/builds/worker/workspace/obj-build/dist/include/nsWindowsDllInterceptor.h @ 254] 0a 0000001f`e6ffe360 00007ff9`39bbbb92 firefox!mozilla::freestanding::patched_LdrLoadDll+0x1b3 [/builds/worker/checkouts/gecko/browser/app/winlauncher/freestanding/DllBlocklist.cpp @ 360] 0b 0000001f`e6ffe440 00007ff9`3a51e067 KERNELBASE!LoadLibraryExW+0x172 0c 0000001f`e6ffe4b0 00007ff9`3c4f2c94 user32!_ClientLoadLibrary+0xa7 0d 0000001f`e6ffe650 00007ff9`39f314d4 ntdll!KiUserCallbackDispatcherContinue 0e 0000001f`e6ffe768 00007ff9`3a531bdf win32u!NtUserPeekMessage+0x14 0f 0000001f`e6ffe770 00007ff9`3a531aac user32!_PeekMessage+0x3f 10 0000001f`e6ffe7e0 00007ff8`63d37d4c user32!PeekMessageW+0x9c ... # Child-SP RetAddr Call Site 00 0000001f`e6ffdb98 00007ff6`2bdb0885 0x00000216`7a8c2cb4 (orig_QueryAttributes) 01 0000001f`e6ffdba0 00007ff9`3c47ac39 firefox!TargetNtQueryAttributesFile+0x35 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/filesystem_interception.cc @ 204] 02 0000001f`e6ffdce0 00007ff9`3c47a3f7 ntdll!LdrpGetNtPathFromDosPath+0x95 03 0000001f`e6ffddc0 00007ff9`3c461072 ntdll!LdrpResolveDllName+0x103 04 0000001f`e6ffde30 00007ff9`3c460eaf ntdll!LdrpMapDllFullPath+0x72 05 0000001f`e6ffdfc0 00007ff9`3c4788c4 ntdll!LdrpProcessWork+0x77 06 0000001f`e6ffe010 00007ff9`3c468c9c ntdll!LdrpLoadDllInternal+0x1a0 07 0000001f`e6ffe0b0 00007ff9`3c47a24a ntdll!LdrpLoadDll+0xb0 08 0000001f`e6ffe270 00007ff6`2bd98803 ntdll!LdrLoadDll+0xfa 09 (Inline Function) --------`-------- firefox!mozilla::interceptor::FuncHookCrossProcess<mozilla::interceptor::WindowsDllInterceptor<mozilla::interceptor::VMSharingPolicyUnique<mozilla::interceptor::MMPolicyOutOfProcess> >,long (*)(wchar_t *, unsigned long *, _UNICODE_STRING *, void **)>::operator()+0x19 [/builds/worker/workspace/obj-build/dist/include/nsWindowsDllInterceptor.h @ 254] 0a 0000001f`e6ffe360 00007ff9`39bbbb92 firefox!mozilla::freestanding::patched_LdrLoadDll+0x1b3 [/builds/worker/checkouts/gecko/browser/app/winlauncher/freestanding/DllBlocklist.cpp @ 360] 0b 0000001f`e6ffe440 00007ff9`3a51e067 KERNELBASE!LoadLibraryExW+0x172 0c 0000001f`e6ffe4b0 00007ff9`3c4f2c94 user32!_ClientLoadLibrary+0xa7 0d 0000001f`e6ffe650 00007ff9`39f314d4 ntdll!KiUserCallbackDispatcherContinue 0e 0000001f`e6ffe768 00007ff9`3a531bdf win32u!NtUserPeekMessage+0x14 0f 0000001f`e6ffe770 00007ff9`3a531aac user32!_PeekMessage+0x3f 10 0000001f`e6ffe7e0 00007ff8`63d37d4c user32!PeekMessageW+0x9c ... ``` Now, why do we not have full stacks for `orig_OpenFile`, `orig_QueryAttributes`, `NtClose`, `NtCreateSection`, `ZwMapViewOfSection`, `ZwQueryVirtualMemory`, `ZwUnmapViewOfSection`? Because they all happen in `LdrLoadDll`, and before calling into `LdrLoadDll` we [disable](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#37) stack walking [over concerns about the function table locks](https://searchfox.org/mozilla-central/source/mozglue/misc/StackWalk.cpp#112-115), and we [restore](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#50) it only after the call. So even though these calls seem to appear out of nowhere in the profile, they should be understood as having the same call stack as what I just shared above. When we understand that, it confirms that the process spends ~100% of its time in `nsThread::ProcessNextEvent`. In fact, we are facing an infinite cycle of events, where the code that we execute to process an event will itself generate a new (DLL load) event that needs to be processed, and again, leaving the process no time to rest. Here is how the cycle appears: - a first legitimate native event arrives; - we reach `nsThread::ProcessNextEvent` to look for an event; - that calls into `nsBaseAppShell::OnProcessNextEvent`, which calls into `PeekMessageW`; - there is an event, and `pmls64.dll` is not loaded yet, so we reach `_ClientLoadLibrary` to load `pmls64.dll` where the registered hook lives; - that calls `patched_LdrLoadDll`, which will fail to load the DLL, then will call into `DllServices::DispatchDllLoadNotification` to register a new DLL load event for the main thread, without actually posting it for the moment; - since loading the DLL failed, we handle the original event without applying the hook, then we return from `PeekMessageW`; - the next call to `nsThread::ProcessNextEvent` will reach `EnsureMainThreadTasksScheduled`, where the DLL load event will be posted with `PostMessage` as a new legitimate native event, right before going into `nsBaseAppShell::OnProcessNextEvent`, thus starting a new iteration of the cycle. Note that when we only have a cycle because of blocking. If we do not block a DLL, we avoid the cycle: - if the DLL loads successfully, further calls into `PeekMessageW` will not call into `_ClientLoadLibrary` for the same library anymore, they will call the hook directly; - if the DLL fails to load for another reason than blocking (e.g. `DllMain` returns `FALSE` on `DLL_PROCESS_ATTACH`), [we do not generate any DLL load event](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#61-66). The cycle described above exists even when the profiler is not attached.
Thanks Greg and Molly for your comments, they were helpful. Indeed my first comment was wrong. I managed to reproduce exactly the profile shared in the description. It happens when a DLL that is registered with `SetWindowsHookExW` for `WH_GETMESSAGE` gets blocked by our blocklist. I managed to reproduce the profile by registering my own DLL and blocking it in `about:third-party`, then I realized that the story is a little bit different for `pmls64.dll`... (In reply to Greg Stoll from comment #2) > We have seen issues like this before when we add a DLL that gets loaded by a window hook to the DLL blocklist, and our advice is...[don't block those DLLs](https://firefox-source-docs.mozilla.org/widget/windows/blocklist.html#cases-where-we-should-not-block-a-module), which isn't helpful in this case since we're not doing the blocking. ... In fact [we **are** doing the blocking](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/WindowsDllBlocklistDefs.in#163)! This DLL is hard-blocked in our static blocklist. First let me clarify what we see in the profile now that I understand it better. For a start, the raw addresses ending in 74 and b4 without symbols correspond to the following stacks: ``` # Child-SP RetAddr Call Site 00 0000001f`e6ffdb78 00007ff6`2bdb03d6 0x00000216`7a8c2c74 (orig_OpenFile) 01 0000001f`e6ffdb80 00007ff6`2bdb5125 firefox!TargetNtOpenFile+0x56 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/filesystem_interception.cc @ 125] 02 0000001f`e6ffdcf0 00007ff9`3c46064c firefox!TargetNtOpenFile64+0x35 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/interceptors_64.cc @ 120] 03 0000001f`e6ffdd30 00007ff9`3c4610e0 ntdll!LdrpMapDllNtFileName+0xe8 04 0000001f`e6ffde30 00007ff9`3c460eaf ntdll!LdrpMapDllFullPath+0xe0 05 0000001f`e6ffdfc0 00007ff9`3c4788c4 ntdll!LdrpProcessWork+0x77 06 0000001f`e6ffe010 00007ff9`3c468c9c ntdll!LdrpLoadDllInternal+0x1a0 07 0000001f`e6ffe0b0 00007ff9`3c47a24a ntdll!LdrpLoadDll+0xb0 08 0000001f`e6ffe270 00007ff6`2bd98803 ntdll!LdrLoadDll+0xfa 09 (Inline Function) --------`-------- firefox!mozilla::interceptor::FuncHookCrossProcess<mozilla::interceptor::WindowsDllInterceptor<mozilla::interceptor::VMSharingPolicyUnique<mozilla::interceptor::MMPolicyOutOfProcess> >,long (*)(wchar_t *, unsigned long *, _UNICODE_STRING *, void **)>::operator()+0x19 [/builds/worker/workspace/obj-build/dist/include/nsWindowsDllInterceptor.h @ 254] 0a 0000001f`e6ffe360 00007ff9`39bbbb92 firefox!mozilla::freestanding::patched_LdrLoadDll+0x1b3 [/builds/worker/checkouts/gecko/browser/app/winlauncher/freestanding/DllBlocklist.cpp @ 360] 0b 0000001f`e6ffe440 00007ff9`3a51e067 KERNELBASE!LoadLibraryExW+0x172 0c 0000001f`e6ffe4b0 00007ff9`3c4f2c94 user32!_ClientLoadLibrary+0xa7 0d 0000001f`e6ffe650 00007ff9`39f314d4 ntdll!KiUserCallbackDispatcherContinue 0e 0000001f`e6ffe768 00007ff9`3a531bdf win32u!NtUserPeekMessage+0x14 0f 0000001f`e6ffe770 00007ff9`3a531aac user32!_PeekMessage+0x3f 10 0000001f`e6ffe7e0 00007ff8`63d37d4c user32!PeekMessageW+0x9c ... # Child-SP RetAddr Call Site 00 0000001f`e6ffdb98 00007ff6`2bdb0885 0x00000216`7a8c2cb4 (orig_QueryAttributes) 01 0000001f`e6ffdba0 00007ff9`3c47ac39 firefox!TargetNtQueryAttributesFile+0x35 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/filesystem_interception.cc @ 204] 02 0000001f`e6ffdce0 00007ff9`3c47a3f7 ntdll!LdrpGetNtPathFromDosPath+0x95 03 0000001f`e6ffddc0 00007ff9`3c461072 ntdll!LdrpResolveDllName+0x103 04 0000001f`e6ffde30 00007ff9`3c460eaf ntdll!LdrpMapDllFullPath+0x72 05 0000001f`e6ffdfc0 00007ff9`3c4788c4 ntdll!LdrpProcessWork+0x77 06 0000001f`e6ffe010 00007ff9`3c468c9c ntdll!LdrpLoadDllInternal+0x1a0 07 0000001f`e6ffe0b0 00007ff9`3c47a24a ntdll!LdrpLoadDll+0xb0 08 0000001f`e6ffe270 00007ff6`2bd98803 ntdll!LdrLoadDll+0xfa 09 (Inline Function) --------`-------- firefox!mozilla::interceptor::FuncHookCrossProcess<mozilla::interceptor::WindowsDllInterceptor<mozilla::interceptor::VMSharingPolicyUnique<mozilla::interceptor::MMPolicyOutOfProcess> >,long (*)(wchar_t *, unsigned long *, _UNICODE_STRING *, void **)>::operator()+0x19 [/builds/worker/workspace/obj-build/dist/include/nsWindowsDllInterceptor.h @ 254] 0a 0000001f`e6ffe360 00007ff9`39bbbb92 firefox!mozilla::freestanding::patched_LdrLoadDll+0x1b3 [/builds/worker/checkouts/gecko/browser/app/winlauncher/freestanding/DllBlocklist.cpp @ 360] 0b 0000001f`e6ffe440 00007ff9`3a51e067 KERNELBASE!LoadLibraryExW+0x172 0c 0000001f`e6ffe4b0 00007ff9`3c4f2c94 user32!_ClientLoadLibrary+0xa7 0d 0000001f`e6ffe650 00007ff9`39f314d4 ntdll!KiUserCallbackDispatcherContinue 0e 0000001f`e6ffe768 00007ff9`3a531bdf win32u!NtUserPeekMessage+0x14 0f 0000001f`e6ffe770 00007ff9`3a531aac user32!_PeekMessage+0x3f 10 0000001f`e6ffe7e0 00007ff8`63d37d4c user32!PeekMessageW+0x9c ... ``` Now, why do we not have full stacks for `orig_OpenFile`, `orig_QueryAttributes`, `NtClose`, `NtCreateSection`, `ZwMapViewOfSection`, `ZwQueryVirtualMemory`, `ZwUnmapViewOfSection`? Because they all happen in `LdrLoadDll`, and before calling into `LdrLoadDll` we [disable](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#37) stack walking [over concerns about the function table locks](https://searchfox.org/mozilla-central/source/mozglue/misc/StackWalk.cpp#112-115), and we [restore](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#50) it only after the call. So even though these calls seem to appear out of nowhere in the profile, they should be understood as having the same call stack as what I just shared above. When we understand that, it confirms that the process spends ~100% of its time in `nsThread::ProcessNextEvent`. In fact, we are facing an infinite cycle of events, where the code that we execute to process an event will itself generate a new (DLL load) event that needs to be processed, and again, leaving the process no time to rest. Here is how the cycle appears: - a first legitimate native event arrives; - we reach `nsThread::ProcessNextEvent` to look for an event; - that calls into `nsBaseAppShell::OnProcessNextEvent`, which calls into `PeekMessageW`; - there is an event, and `pmls64.dll` is not loaded yet, so we reach `_ClientLoadLibrary` to load `pmls64.dll` where the registered hook lives; - that calls `patched_LdrLoadDll`, which will fail to load the DLL, then will call into `DllServices::DispatchDllLoadNotification` to register a new DLL load event for the main thread, without actually posting it for the moment; - since loading the DLL failed, we handle the original event without applying the hook, then we return from `PeekMessageW`; - the next call to `nsThread::ProcessNextEvent` will reach `EnsureMainThreadTasksScheduled`, where the DLL load event will be posted with `PostMessage` as a new legitimate native event, right before going into `nsBaseAppShell::OnProcessNextEvent`, thus starting a new iteration of the cycle. Note that when we only have a cycle because of blocking. If we do not block a DLL, we avoid the cycle: - if the DLL loads successfully, further calls into `PeekMessageW` will not call into `_ClientLoadLibrary` for the same library anymore, they will call the hook directly; - if the DLL fails to load for another reason than blocking (e.g. `DllMain` returns `FALSE` on `DLL_PROCESS_ATTACH`), [we do not generate any DLL load event](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#61-66). The cycle described above exists even when the profiler is not attached.
Thanks Greg and Molly for your comments, they were helpful. Indeed my first comment was wrong. I managed to reproduce exactly the profile shared in the description. It happens when a DLL that is registered with `SetWindowsHookExW` for `WH_GETMESSAGE` gets blocked by our blocklist. I managed to reproduce the profile by registering my own DLL and blocking it in `about:third-party`, then I realized that the story is a little bit different for `pmls64.dll`... (In reply to Greg Stoll from comment #2) > We have seen issues like this before when we add a DLL that gets loaded by a window hook to the DLL blocklist, and our advice is...[don't block those DLLs](https://firefox-source-docs.mozilla.org/widget/windows/blocklist.html#cases-where-we-should-not-block-a-module), which isn't helpful in this case since we're not doing the blocking. ... In fact [we **are** doing the blocking](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/WindowsDllBlocklistDefs.in#163)! This DLL is hard-blocked in our static blocklist. First let me clarify what we see in the profile now that I understand it better. For a start, the raw addresses ending in 74 and b4 without symbols correspond to the following stacks: ``` # Child-SP RetAddr Call Site 00 0000001f`e6ffdb78 00007ff6`2bdb03d6 0x00000216`7a8c2c74 (orig_OpenFile) 01 0000001f`e6ffdb80 00007ff6`2bdb5125 firefox!TargetNtOpenFile+0x56 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/filesystem_interception.cc @ 125] 02 0000001f`e6ffdcf0 00007ff9`3c46064c firefox!TargetNtOpenFile64+0x35 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/interceptors_64.cc @ 120] 03 0000001f`e6ffdd30 00007ff9`3c4610e0 ntdll!LdrpMapDllNtFileName+0xe8 04 0000001f`e6ffde30 00007ff9`3c460eaf ntdll!LdrpMapDllFullPath+0xe0 05 0000001f`e6ffdfc0 00007ff9`3c4788c4 ntdll!LdrpProcessWork+0x77 06 0000001f`e6ffe010 00007ff9`3c468c9c ntdll!LdrpLoadDllInternal+0x1a0 07 0000001f`e6ffe0b0 00007ff9`3c47a24a ntdll!LdrpLoadDll+0xb0 08 0000001f`e6ffe270 00007ff6`2bd98803 ntdll!LdrLoadDll+0xfa 09 (Inline Function) --------`-------- firefox!mozilla::interceptor::FuncHookCrossProcess<mozilla::interceptor::WindowsDllInterceptor<mozilla::interceptor::VMSharingPolicyUnique<mozilla::interceptor::MMPolicyOutOfProcess> >,long (*)(wchar_t *, unsigned long *, _UNICODE_STRING *, void **)>::operator()+0x19 [/builds/worker/workspace/obj-build/dist/include/nsWindowsDllInterceptor.h @ 254] 0a 0000001f`e6ffe360 00007ff9`39bbbb92 firefox!mozilla::freestanding::patched_LdrLoadDll+0x1b3 [/builds/worker/checkouts/gecko/browser/app/winlauncher/freestanding/DllBlocklist.cpp @ 360] 0b 0000001f`e6ffe440 00007ff9`3a51e067 KERNELBASE!LoadLibraryExW+0x172 0c 0000001f`e6ffe4b0 00007ff9`3c4f2c94 user32!_ClientLoadLibrary+0xa7 0d 0000001f`e6ffe650 00007ff9`39f314d4 ntdll!KiUserCallbackDispatcherContinue 0e 0000001f`e6ffe768 00007ff9`3a531bdf win32u!NtUserPeekMessage+0x14 0f 0000001f`e6ffe770 00007ff9`3a531aac user32!_PeekMessage+0x3f 10 0000001f`e6ffe7e0 00007ff8`63d37d4c user32!PeekMessageW+0x9c ... # Child-SP RetAddr Call Site 00 0000001f`e6ffdb98 00007ff6`2bdb0885 0x00000216`7a8c2cb4 (orig_QueryAttributes) 01 0000001f`e6ffdba0 00007ff9`3c47ac39 firefox!TargetNtQueryAttributesFile+0x35 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/filesystem_interception.cc @ 204] 02 0000001f`e6ffdce0 00007ff9`3c47a3f7 ntdll!LdrpGetNtPathFromDosPath+0x95 03 0000001f`e6ffddc0 00007ff9`3c461072 ntdll!LdrpResolveDllName+0x103 04 0000001f`e6ffde30 00007ff9`3c460eaf ntdll!LdrpMapDllFullPath+0x72 05 0000001f`e6ffdfc0 00007ff9`3c4788c4 ntdll!LdrpProcessWork+0x77 06 0000001f`e6ffe010 00007ff9`3c468c9c ntdll!LdrpLoadDllInternal+0x1a0 07 0000001f`e6ffe0b0 00007ff9`3c47a24a ntdll!LdrpLoadDll+0xb0 08 0000001f`e6ffe270 00007ff6`2bd98803 ntdll!LdrLoadDll+0xfa 09 (Inline Function) --------`-------- firefox!mozilla::interceptor::FuncHookCrossProcess<mozilla::interceptor::WindowsDllInterceptor<mozilla::interceptor::VMSharingPolicyUnique<mozilla::interceptor::MMPolicyOutOfProcess> >,long (*)(wchar_t *, unsigned long *, _UNICODE_STRING *, void **)>::operator()+0x19 [/builds/worker/workspace/obj-build/dist/include/nsWindowsDllInterceptor.h @ 254] 0a 0000001f`e6ffe360 00007ff9`39bbbb92 firefox!mozilla::freestanding::patched_LdrLoadDll+0x1b3 [/builds/worker/checkouts/gecko/browser/app/winlauncher/freestanding/DllBlocklist.cpp @ 360] 0b 0000001f`e6ffe440 00007ff9`3a51e067 KERNELBASE!LoadLibraryExW+0x172 0c 0000001f`e6ffe4b0 00007ff9`3c4f2c94 user32!_ClientLoadLibrary+0xa7 0d 0000001f`e6ffe650 00007ff9`39f314d4 ntdll!KiUserCallbackDispatcherContinue 0e 0000001f`e6ffe768 00007ff9`3a531bdf win32u!NtUserPeekMessage+0x14 0f 0000001f`e6ffe770 00007ff9`3a531aac user32!_PeekMessage+0x3f 10 0000001f`e6ffe7e0 00007ff8`63d37d4c user32!PeekMessageW+0x9c ... ``` Now, why do we not have full stacks for `orig_OpenFile`, `orig_QueryAttributes`, `NtClose`, `NtCreateSection`, `ZwMapViewOfSection`, `ZwQueryVirtualMemory`, `ZwUnmapViewOfSection`? Because they all happen in `LdrLoadDll`, and before calling into `LdrLoadDll` we [disable](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#37) stack walking [over concerns about the function table locks](https://searchfox.org/mozilla-central/source/mozglue/misc/StackWalk.cpp#112-115), and we [restore](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#50) it only after the call. So even though these calls seem to appear out of nowhere in the profile, they should be understood as having the same call stack as what I just shared above. When we understand that, it confirms that the process spends ~100% of its time in `nsThread::ProcessNextEvent`. In fact, we are facing an infinite cycle of events, where the code that we execute to process an event will itself generate a new DLL load event that needs to be processed, and again, leaving the process no time to rest. Here is how the cycle appears: - a first legitimate native event arrives; - we reach `nsThread::ProcessNextEvent` to look for an event; - that calls into `nsBaseAppShell::OnProcessNextEvent`, which calls into `PeekMessageW`; - there is an event, and `pmls64.dll` is not loaded yet, so we reach `_ClientLoadLibrary` to load `pmls64.dll` where the registered hook lives; - that calls `patched_LdrLoadDll`, which will fail to load the DLL, then will call into `DllServices::DispatchDllLoadNotification` to register a new DLL load event for the main thread, without actually posting it for the moment; - since loading the DLL failed, we handle the original event without applying the hook, then we return from `PeekMessageW`; - the next call to `nsThread::ProcessNextEvent` will reach `EnsureMainThreadTasksScheduled`, where the DLL load event will be posted with `PostMessage` as a new legitimate native event, right before going into `nsBaseAppShell::OnProcessNextEvent`, thus starting a new iteration of the cycle. Note that when we only have a cycle because of blocking. If we do not block a DLL, we avoid the cycle: - if the DLL loads successfully, further calls into `PeekMessageW` will not call into `_ClientLoadLibrary` for the same library anymore, they will call the hook directly; - if the DLL fails to load for another reason than blocking (e.g. `DllMain` returns `FALSE` on `DLL_PROCESS_ATTACH`), [we do not generate any DLL load event](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#61-66). The cycle described above exists even when the profiler is not attached.
Thanks Greg and Molly for your comments, they were helpful. Indeed my first comment was incorrect. I managed to reproduce exactly the profile shared in the description. It happens when a DLL that is registered with `SetWindowsHookExW` for `WH_GETMESSAGE` gets blocked by our blocklist. I managed to reproduce the profile by registering my own DLL and blocking it in `about:third-party`, then I realized that the story is a little bit different for `pmls64.dll`... (In reply to Greg Stoll from comment #2) > We have seen issues like this before when we add a DLL that gets loaded by a window hook to the DLL blocklist, and our advice is...[don't block those DLLs](https://firefox-source-docs.mozilla.org/widget/windows/blocklist.html#cases-where-we-should-not-block-a-module), which isn't helpful in this case since we're not doing the blocking. ... In fact [we **are** doing the blocking](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/WindowsDllBlocklistDefs.in#163)! This DLL is hard-blocked in our static blocklist. First let me clarify what we see in the profile now that I understand it better. For a start, the raw addresses ending in 74 and b4 without symbols correspond to the following stacks: ``` # Child-SP RetAddr Call Site 00 0000001f`e6ffdb78 00007ff6`2bdb03d6 0x00000216`7a8c2c74 (orig_OpenFile) 01 0000001f`e6ffdb80 00007ff6`2bdb5125 firefox!TargetNtOpenFile+0x56 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/filesystem_interception.cc @ 125] 02 0000001f`e6ffdcf0 00007ff9`3c46064c firefox!TargetNtOpenFile64+0x35 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/interceptors_64.cc @ 120] 03 0000001f`e6ffdd30 00007ff9`3c4610e0 ntdll!LdrpMapDllNtFileName+0xe8 04 0000001f`e6ffde30 00007ff9`3c460eaf ntdll!LdrpMapDllFullPath+0xe0 05 0000001f`e6ffdfc0 00007ff9`3c4788c4 ntdll!LdrpProcessWork+0x77 06 0000001f`e6ffe010 00007ff9`3c468c9c ntdll!LdrpLoadDllInternal+0x1a0 07 0000001f`e6ffe0b0 00007ff9`3c47a24a ntdll!LdrpLoadDll+0xb0 08 0000001f`e6ffe270 00007ff6`2bd98803 ntdll!LdrLoadDll+0xfa 09 (Inline Function) --------`-------- firefox!mozilla::interceptor::FuncHookCrossProcess<mozilla::interceptor::WindowsDllInterceptor<mozilla::interceptor::VMSharingPolicyUnique<mozilla::interceptor::MMPolicyOutOfProcess> >,long (*)(wchar_t *, unsigned long *, _UNICODE_STRING *, void **)>::operator()+0x19 [/builds/worker/workspace/obj-build/dist/include/nsWindowsDllInterceptor.h @ 254] 0a 0000001f`e6ffe360 00007ff9`39bbbb92 firefox!mozilla::freestanding::patched_LdrLoadDll+0x1b3 [/builds/worker/checkouts/gecko/browser/app/winlauncher/freestanding/DllBlocklist.cpp @ 360] 0b 0000001f`e6ffe440 00007ff9`3a51e067 KERNELBASE!LoadLibraryExW+0x172 0c 0000001f`e6ffe4b0 00007ff9`3c4f2c94 user32!_ClientLoadLibrary+0xa7 0d 0000001f`e6ffe650 00007ff9`39f314d4 ntdll!KiUserCallbackDispatcherContinue 0e 0000001f`e6ffe768 00007ff9`3a531bdf win32u!NtUserPeekMessage+0x14 0f 0000001f`e6ffe770 00007ff9`3a531aac user32!_PeekMessage+0x3f 10 0000001f`e6ffe7e0 00007ff8`63d37d4c user32!PeekMessageW+0x9c ... # Child-SP RetAddr Call Site 00 0000001f`e6ffdb98 00007ff6`2bdb0885 0x00000216`7a8c2cb4 (orig_QueryAttributes) 01 0000001f`e6ffdba0 00007ff9`3c47ac39 firefox!TargetNtQueryAttributesFile+0x35 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/filesystem_interception.cc @ 204] 02 0000001f`e6ffdce0 00007ff9`3c47a3f7 ntdll!LdrpGetNtPathFromDosPath+0x95 03 0000001f`e6ffddc0 00007ff9`3c461072 ntdll!LdrpResolveDllName+0x103 04 0000001f`e6ffde30 00007ff9`3c460eaf ntdll!LdrpMapDllFullPath+0x72 05 0000001f`e6ffdfc0 00007ff9`3c4788c4 ntdll!LdrpProcessWork+0x77 06 0000001f`e6ffe010 00007ff9`3c468c9c ntdll!LdrpLoadDllInternal+0x1a0 07 0000001f`e6ffe0b0 00007ff9`3c47a24a ntdll!LdrpLoadDll+0xb0 08 0000001f`e6ffe270 00007ff6`2bd98803 ntdll!LdrLoadDll+0xfa 09 (Inline Function) --------`-------- firefox!mozilla::interceptor::FuncHookCrossProcess<mozilla::interceptor::WindowsDllInterceptor<mozilla::interceptor::VMSharingPolicyUnique<mozilla::interceptor::MMPolicyOutOfProcess> >,long (*)(wchar_t *, unsigned long *, _UNICODE_STRING *, void **)>::operator()+0x19 [/builds/worker/workspace/obj-build/dist/include/nsWindowsDllInterceptor.h @ 254] 0a 0000001f`e6ffe360 00007ff9`39bbbb92 firefox!mozilla::freestanding::patched_LdrLoadDll+0x1b3 [/builds/worker/checkouts/gecko/browser/app/winlauncher/freestanding/DllBlocklist.cpp @ 360] 0b 0000001f`e6ffe440 00007ff9`3a51e067 KERNELBASE!LoadLibraryExW+0x172 0c 0000001f`e6ffe4b0 00007ff9`3c4f2c94 user32!_ClientLoadLibrary+0xa7 0d 0000001f`e6ffe650 00007ff9`39f314d4 ntdll!KiUserCallbackDispatcherContinue 0e 0000001f`e6ffe768 00007ff9`3a531bdf win32u!NtUserPeekMessage+0x14 0f 0000001f`e6ffe770 00007ff9`3a531aac user32!_PeekMessage+0x3f 10 0000001f`e6ffe7e0 00007ff8`63d37d4c user32!PeekMessageW+0x9c ... ``` Now, why do we not have full stacks for `orig_OpenFile`, `orig_QueryAttributes`, `NtClose`, `NtCreateSection`, `ZwMapViewOfSection`, `ZwQueryVirtualMemory`, `ZwUnmapViewOfSection`? Because they all happen in `LdrLoadDll`, and before calling into `LdrLoadDll` we [disable](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#37) stack walking [over concerns about the function table locks](https://searchfox.org/mozilla-central/source/mozglue/misc/StackWalk.cpp#112-115), and we [restore](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#50) it only after the call. So even though these calls seem to appear out of nowhere in the profile, they should be understood as having the same call stack as what I just shared above. When we understand that, it confirms that the process spends ~100% of its time in `nsThread::ProcessNextEvent`. In fact, we are facing an infinite cycle of events, where the code that we execute to process an event will itself generate a new DLL load event that needs to be processed, and again, leaving the process no time to rest. Here is how the cycle appears: - a first legitimate native event arrives; - we reach `nsThread::ProcessNextEvent` to look for an event; - that calls into `nsBaseAppShell::OnProcessNextEvent`, which calls into `PeekMessageW`; - there is an event, and `pmls64.dll` is not loaded yet, so we reach `_ClientLoadLibrary` to load `pmls64.dll` where the registered hook lives; - that calls `patched_LdrLoadDll`, which will fail to load the DLL, then will call into `DllServices::DispatchDllLoadNotification` to register a new DLL load event for the main thread, without actually posting it for the moment; - since loading the DLL failed, we handle the original event without applying the hook, then we return from `PeekMessageW`; - the next call to `nsThread::ProcessNextEvent` will reach `EnsureMainThreadTasksScheduled`, where the DLL load event will be posted with `PostMessage` as a new legitimate native event, right before going into `nsBaseAppShell::OnProcessNextEvent`, thus starting a new iteration of the cycle. Note that when we only have a cycle because of blocking. If we do not block a DLL, we avoid the cycle: - if the DLL loads successfully, further calls into `PeekMessageW` will not call into `_ClientLoadLibrary` for the same library anymore, they will call the hook directly; - if the DLL fails to load for another reason than blocking (e.g. `DllMain` returns `FALSE` on `DLL_PROCESS_ATTACH`), [we do not generate any DLL load event](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#61-66). The cycle described above exists even when the profiler is not attached.
Thanks Greg and Molly for your comments, they were helpful. Indeed my first comment was incorrect. I managed to reproduce exactly the profile shared in the description. It happens when a DLL that is registered with `SetWindowsHookExW` for `WH_GETMESSAGE` gets blocked by our blocklist. I managed to reproduce the profile by registering my own DLL and blocking it in `about:third-party`, then I realized that the story is a little bit different for `pmls64.dll`... (In reply to Greg Stoll from comment #2) > We have seen issues like this before when we add a DLL that gets loaded by a window hook to the DLL blocklist, and our advice is...[don't block those DLLs](https://firefox-source-docs.mozilla.org/widget/windows/blocklist.html#cases-where-we-should-not-block-a-module), which isn't helpful in this case since we're not doing the blocking. ... In fact [we **are** doing the blocking](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/WindowsDllBlocklistDefs.in#163)! This DLL is hard-blocked in our static blocklist. First let me clarify what we see in the profile now that I understand it better. For a start, the raw addresses ending in 74 and b4 without symbols correspond to the following stacks: ``` # Child-SP RetAddr Call Site 00 0000001f`e6ffdb78 00007ff6`2bdb03d6 0x00000216`7a8c2c74 (orig_OpenFile) 01 0000001f`e6ffdb80 00007ff6`2bdb5125 firefox!TargetNtOpenFile+0x56 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/filesystem_interception.cc @ 125] 02 0000001f`e6ffdcf0 00007ff9`3c46064c firefox!TargetNtOpenFile64+0x35 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/interceptors_64.cc @ 120] 03 0000001f`e6ffdd30 00007ff9`3c4610e0 ntdll!LdrpMapDllNtFileName+0xe8 04 0000001f`e6ffde30 00007ff9`3c460eaf ntdll!LdrpMapDllFullPath+0xe0 05 0000001f`e6ffdfc0 00007ff9`3c4788c4 ntdll!LdrpProcessWork+0x77 06 0000001f`e6ffe010 00007ff9`3c468c9c ntdll!LdrpLoadDllInternal+0x1a0 07 0000001f`e6ffe0b0 00007ff9`3c47a24a ntdll!LdrpLoadDll+0xb0 08 0000001f`e6ffe270 00007ff6`2bd98803 ntdll!LdrLoadDll+0xfa 09 (Inline Function) --------`-------- firefox!mozilla::interceptor::FuncHookCrossProcess<mozilla::interceptor::WindowsDllInterceptor<mozilla::interceptor::VMSharingPolicyUnique<mozilla::interceptor::MMPolicyOutOfProcess> >,long (*)(wchar_t *, unsigned long *, _UNICODE_STRING *, void **)>::operator()+0x19 [/builds/worker/workspace/obj-build/dist/include/nsWindowsDllInterceptor.h @ 254] 0a 0000001f`e6ffe360 00007ff9`39bbbb92 firefox!mozilla::freestanding::patched_LdrLoadDll+0x1b3 [/builds/worker/checkouts/gecko/browser/app/winlauncher/freestanding/DllBlocklist.cpp @ 360] 0b 0000001f`e6ffe440 00007ff9`3a51e067 KERNELBASE!LoadLibraryExW+0x172 0c 0000001f`e6ffe4b0 00007ff9`3c4f2c94 user32!_ClientLoadLibrary+0xa7 0d 0000001f`e6ffe650 00007ff9`39f314d4 ntdll!KiUserCallbackDispatcherContinue 0e 0000001f`e6ffe768 00007ff9`3a531bdf win32u!NtUserPeekMessage+0x14 0f 0000001f`e6ffe770 00007ff9`3a531aac user32!_PeekMessage+0x3f 10 0000001f`e6ffe7e0 00007ff8`63d37d4c user32!PeekMessageW+0x9c ... # Child-SP RetAddr Call Site 00 0000001f`e6ffdb98 00007ff6`2bdb0885 0x00000216`7a8c2cb4 (orig_QueryAttributes) 01 0000001f`e6ffdba0 00007ff9`3c47ac39 firefox!TargetNtQueryAttributesFile+0x35 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/filesystem_interception.cc @ 204] 02 0000001f`e6ffdce0 00007ff9`3c47a3f7 ntdll!LdrpGetNtPathFromDosPath+0x95 03 0000001f`e6ffddc0 00007ff9`3c461072 ntdll!LdrpResolveDllName+0x103 04 0000001f`e6ffde30 00007ff9`3c460eaf ntdll!LdrpMapDllFullPath+0x72 05 0000001f`e6ffdfc0 00007ff9`3c4788c4 ntdll!LdrpProcessWork+0x77 06 0000001f`e6ffe010 00007ff9`3c468c9c ntdll!LdrpLoadDllInternal+0x1a0 07 0000001f`e6ffe0b0 00007ff9`3c47a24a ntdll!LdrpLoadDll+0xb0 08 0000001f`e6ffe270 00007ff6`2bd98803 ntdll!LdrLoadDll+0xfa 09 (Inline Function) --------`-------- firefox!mozilla::interceptor::FuncHookCrossProcess<mozilla::interceptor::WindowsDllInterceptor<mozilla::interceptor::VMSharingPolicyUnique<mozilla::interceptor::MMPolicyOutOfProcess> >,long (*)(wchar_t *, unsigned long *, _UNICODE_STRING *, void **)>::operator()+0x19 [/builds/worker/workspace/obj-build/dist/include/nsWindowsDllInterceptor.h @ 254] 0a 0000001f`e6ffe360 00007ff9`39bbbb92 firefox!mozilla::freestanding::patched_LdrLoadDll+0x1b3 [/builds/worker/checkouts/gecko/browser/app/winlauncher/freestanding/DllBlocklist.cpp @ 360] 0b 0000001f`e6ffe440 00007ff9`3a51e067 KERNELBASE!LoadLibraryExW+0x172 0c 0000001f`e6ffe4b0 00007ff9`3c4f2c94 user32!_ClientLoadLibrary+0xa7 0d 0000001f`e6ffe650 00007ff9`39f314d4 ntdll!KiUserCallbackDispatcherContinue 0e 0000001f`e6ffe768 00007ff9`3a531bdf win32u!NtUserPeekMessage+0x14 0f 0000001f`e6ffe770 00007ff9`3a531aac user32!_PeekMessage+0x3f 10 0000001f`e6ffe7e0 00007ff8`63d37d4c user32!PeekMessageW+0x9c ... ``` Now, why do we not have full stacks in the profile for `orig_OpenFile`, `orig_QueryAttributes`, `NtClose`, `NtCreateSection`, `ZwMapViewOfSection`, `ZwQueryVirtualMemory`, `ZwUnmapViewOfSection`? Because they all happen in `LdrLoadDll`, and before calling into `LdrLoadDll` we [disable](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#37) stack walking [over concerns about the function table locks](https://searchfox.org/mozilla-central/source/mozglue/misc/StackWalk.cpp#112-115), and we [restore](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#50) it only after the call. So even though these calls seem to appear out of nowhere in the profile, they should be understood as having the same call stack as what I just shared above. When we understand that, it confirms that the process spends ~100% of its time in `nsThread::ProcessNextEvent`. In fact, we are facing an infinite cycle of events, where the code that we execute to process an event will itself generate a new DLL load event that needs to be processed, and again, leaving the process no time to rest. Here is how the cycle appears: - a first legitimate native event arrives; - we reach `nsThread::ProcessNextEvent` to look for an event; - that calls into `nsBaseAppShell::OnProcessNextEvent`, which calls into `PeekMessageW`; - there is an event, and `pmls64.dll` is not loaded yet, so we reach `_ClientLoadLibrary` to load `pmls64.dll` where the registered hook lives; - that calls `patched_LdrLoadDll`, which will fail to load the DLL, then will call into `DllServices::DispatchDllLoadNotification` to register a new DLL load event for the main thread, without actually posting it for the moment; - since loading the DLL failed, we handle the original event without applying the hook, then we return from `PeekMessageW`; - the next call to `nsThread::ProcessNextEvent` will reach `EnsureMainThreadTasksScheduled`, where the DLL load event will be posted with `PostMessage` as a new legitimate native event, right before going into `nsBaseAppShell::OnProcessNextEvent`, thus starting a new iteration of the cycle. Note that when we only have a cycle because of blocking. If we do not block a DLL, we avoid the cycle: - if the DLL loads successfully, further calls into `PeekMessageW` will not call into `_ClientLoadLibrary` for the same library anymore, they will call the hook directly; - if the DLL fails to load for another reason than blocking (e.g. `DllMain` returns `FALSE` on `DLL_PROCESS_ATTACH`), [we do not generate any DLL load event](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#61-66). The cycle described above exists even when the profiler is not attached.
Thanks Greg and Molly for your comments, they were helpful. Indeed my first comment was incorrect. I managed to reproduce exactly the profile shared in the description. It happens when a DLL that is registered with `SetWindowsHookExW` for `WH_GETMESSAGE` gets blocked by our blocklist. I managed to reproduce the profile by registering my own DLL and blocking it in `about:third-party`, then I realized that the story is a little bit different for `pmls64.dll`... (In reply to Greg Stoll from comment #2) > We have seen issues like this before when we add a DLL that gets loaded by a window hook to the DLL blocklist, and our advice is...[don't block those DLLs](https://firefox-source-docs.mozilla.org/widget/windows/blocklist.html#cases-where-we-should-not-block-a-module), which isn't helpful in this case since we're not doing the blocking. ... In fact [we **are** doing the blocking](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/WindowsDllBlocklistDefs.in#163)! This DLL is hard-blocked in our static blocklist. First let me clarify what we see in the profile now that I understand it better. For a start, the raw addresses ending in 74 and b4 without symbols correspond to the following stacks: ``` # Child-SP RetAddr Call Site 00 0000001f`e6ffdb78 00007ff6`2bdb03d6 0x00000216`7a8c2c74 (orig_OpenFile) 01 0000001f`e6ffdb80 00007ff6`2bdb5125 firefox!TargetNtOpenFile+0x56 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/filesystem_interception.cc @ 125] 02 0000001f`e6ffdcf0 00007ff9`3c46064c firefox!TargetNtOpenFile64+0x35 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/interceptors_64.cc @ 120] 03 0000001f`e6ffdd30 00007ff9`3c4610e0 ntdll!LdrpMapDllNtFileName+0xe8 04 0000001f`e6ffde30 00007ff9`3c460eaf ntdll!LdrpMapDllFullPath+0xe0 05 0000001f`e6ffdfc0 00007ff9`3c4788c4 ntdll!LdrpProcessWork+0x77 06 0000001f`e6ffe010 00007ff9`3c468c9c ntdll!LdrpLoadDllInternal+0x1a0 07 0000001f`e6ffe0b0 00007ff9`3c47a24a ntdll!LdrpLoadDll+0xb0 08 0000001f`e6ffe270 00007ff6`2bd98803 ntdll!LdrLoadDll+0xfa 09 (Inline Function) --------`-------- firefox!mozilla::interceptor::FuncHookCrossProcess<mozilla::interceptor::WindowsDllInterceptor<mozilla::interceptor::VMSharingPolicyUnique<mozilla::interceptor::MMPolicyOutOfProcess> >,long (*)(wchar_t *, unsigned long *, _UNICODE_STRING *, void **)>::operator()+0x19 [/builds/worker/workspace/obj-build/dist/include/nsWindowsDllInterceptor.h @ 254] 0a 0000001f`e6ffe360 00007ff9`39bbbb92 firefox!mozilla::freestanding::patched_LdrLoadDll+0x1b3 [/builds/worker/checkouts/gecko/browser/app/winlauncher/freestanding/DllBlocklist.cpp @ 360] 0b 0000001f`e6ffe440 00007ff9`3a51e067 KERNELBASE!LoadLibraryExW+0x172 0c 0000001f`e6ffe4b0 00007ff9`3c4f2c94 user32!_ClientLoadLibrary+0xa7 0d 0000001f`e6ffe650 00007ff9`39f314d4 ntdll!KiUserCallbackDispatcherContinue 0e 0000001f`e6ffe768 00007ff9`3a531bdf win32u!NtUserPeekMessage+0x14 0f 0000001f`e6ffe770 00007ff9`3a531aac user32!_PeekMessage+0x3f 10 0000001f`e6ffe7e0 00007ff8`63d37d4c user32!PeekMessageW+0x9c ... # Child-SP RetAddr Call Site 00 0000001f`e6ffdb98 00007ff6`2bdb0885 0x00000216`7a8c2cb4 (orig_QueryAttributes) 01 0000001f`e6ffdba0 00007ff9`3c47ac39 firefox!TargetNtQueryAttributesFile+0x35 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/filesystem_interception.cc @ 204] 02 0000001f`e6ffdce0 00007ff9`3c47a3f7 ntdll!LdrpGetNtPathFromDosPath+0x95 03 0000001f`e6ffddc0 00007ff9`3c461072 ntdll!LdrpResolveDllName+0x103 04 0000001f`e6ffde30 00007ff9`3c460eaf ntdll!LdrpMapDllFullPath+0x72 05 0000001f`e6ffdfc0 00007ff9`3c4788c4 ntdll!LdrpProcessWork+0x77 06 0000001f`e6ffe010 00007ff9`3c468c9c ntdll!LdrpLoadDllInternal+0x1a0 07 0000001f`e6ffe0b0 00007ff9`3c47a24a ntdll!LdrpLoadDll+0xb0 08 0000001f`e6ffe270 00007ff6`2bd98803 ntdll!LdrLoadDll+0xfa 09 (Inline Function) --------`-------- firefox!mozilla::interceptor::FuncHookCrossProcess<mozilla::interceptor::WindowsDllInterceptor<mozilla::interceptor::VMSharingPolicyUnique<mozilla::interceptor::MMPolicyOutOfProcess> >,long (*)(wchar_t *, unsigned long *, _UNICODE_STRING *, void **)>::operator()+0x19 [/builds/worker/workspace/obj-build/dist/include/nsWindowsDllInterceptor.h @ 254] 0a 0000001f`e6ffe360 00007ff9`39bbbb92 firefox!mozilla::freestanding::patched_LdrLoadDll+0x1b3 [/builds/worker/checkouts/gecko/browser/app/winlauncher/freestanding/DllBlocklist.cpp @ 360] 0b 0000001f`e6ffe440 00007ff9`3a51e067 KERNELBASE!LoadLibraryExW+0x172 0c 0000001f`e6ffe4b0 00007ff9`3c4f2c94 user32!_ClientLoadLibrary+0xa7 0d 0000001f`e6ffe650 00007ff9`39f314d4 ntdll!KiUserCallbackDispatcherContinue 0e 0000001f`e6ffe768 00007ff9`3a531bdf win32u!NtUserPeekMessage+0x14 0f 0000001f`e6ffe770 00007ff9`3a531aac user32!_PeekMessage+0x3f 10 0000001f`e6ffe7e0 00007ff8`63d37d4c user32!PeekMessageW+0x9c ... ``` Now, why do we not have full stacks in the profile for `orig_OpenFile`, `orig_QueryAttributes`, `NtClose`, `NtCreateSection`, `ZwMapViewOfSection`, `ZwQueryVirtualMemory`, `ZwUnmapViewOfSection`? Because they all happen in `LdrLoadDll`, and before calling into `LdrLoadDll` we [disable](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#37) stack walking [over concerns about the function table locks](https://searchfox.org/mozilla-central/source/mozglue/misc/StackWalk.cpp#112-115), and we [restore](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#50) it only after the call. So even though these calls seem to appear out of nowhere in the profile, they should be understood as having the same call stack as what I just shared above. When we understand that, it confirms that the process spends ~100% of its time in `nsThread::ProcessNextEvent`. In fact, we are facing an infinite cycle of events, where the code that we execute to process an event will itself generate a new DLL load event that needs to be processed, and again, leaving the process no time to rest. Here is how the cycle appears: - a first legitimate native event arrives; - we reach `nsThread::ProcessNextEvent` to look for an event; - that calls into `nsBaseAppShell::OnProcessNextEvent`, which calls into `PeekMessageW`; - there is an event, and `pmls64.dll` is not loaded yet, so we reach `_ClientLoadLibrary` to load `pmls64.dll` where the registered hook lives; - that calls `patched_LdrLoadDll`, which will fail to load the DLL, then will call into `DllServices::DispatchDllLoadNotification` to register a new DLL load event for the main thread, without actually posting it for the moment; - since loading the DLL failed, we handle the original event without applying the hook, then we return from `PeekMessageW`; - the next call to `nsThread::ProcessNextEvent` will reach `EnsureMainThreadTasksScheduled`, where the DLL load event will be posted with `PostMessage` as a new legitimate native event, right before going into `nsBaseAppShell::OnProcessNextEvent`, thus starting a new iteration of the cycle... Note that when we only have a cycle because of blocking. If we do not block a DLL, we avoid the cycle: - if the DLL loads successfully, further calls into `PeekMessageW` will not call into `_ClientLoadLibrary` for the same library anymore, they will call the hook directly; - if the DLL fails to load for another reason than blocking (e.g. `DllMain` returns `FALSE` on `DLL_PROCESS_ATTACH`), [we do not generate any DLL load event](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#61-66). The cycle described above exists even when the profiler is not attached.
Thanks Greg and Molly for your comments, they were helpful. Indeed my first comment was incorrect. I managed to reproduce exactly the profile shared in the description. It happens when a DLL that is registered with `SetWindowsHookExW` for `WH_GETMESSAGE` gets blocked by our blocklist. I managed to reproduce the profile by registering my own DLL and blocking it in `about:third-party`, then I realized that the story is a little bit different for `pmls64.dll`... (In reply to Greg Stoll from comment #2) > We have seen issues like this before when we add a DLL that gets loaded by a window hook to the DLL blocklist, and our advice is...[don't block those DLLs](https://firefox-source-docs.mozilla.org/widget/windows/blocklist.html#cases-where-we-should-not-block-a-module), which isn't helpful in this case since we're not doing the blocking. ... In fact [we **are** doing the blocking](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/WindowsDllBlocklistDefs.in#163)! This DLL is hard-blocked in our static blocklist. First let me clarify what we see in the profile now that I understand it better. For a start, the raw addresses ending in 74 and b4 without symbols correspond to the following stacks: ``` # Child-SP RetAddr Call Site 00 0000001f`e6ffdb78 00007ff6`2bdb03d6 0x00000216`7a8c2c74 (orig_OpenFile) 01 0000001f`e6ffdb80 00007ff6`2bdb5125 firefox!TargetNtOpenFile+0x56 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/filesystem_interception.cc @ 125] 02 0000001f`e6ffdcf0 00007ff9`3c46064c firefox!TargetNtOpenFile64+0x35 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/interceptors_64.cc @ 120] 03 0000001f`e6ffdd30 00007ff9`3c4610e0 ntdll!LdrpMapDllNtFileName+0xe8 04 0000001f`e6ffde30 00007ff9`3c460eaf ntdll!LdrpMapDllFullPath+0xe0 05 0000001f`e6ffdfc0 00007ff9`3c4788c4 ntdll!LdrpProcessWork+0x77 06 0000001f`e6ffe010 00007ff9`3c468c9c ntdll!LdrpLoadDllInternal+0x1a0 07 0000001f`e6ffe0b0 00007ff9`3c47a24a ntdll!LdrpLoadDll+0xb0 08 0000001f`e6ffe270 00007ff6`2bd98803 ntdll!LdrLoadDll+0xfa 09 (Inline Function) --------`-------- firefox!mozilla::interceptor::FuncHookCrossProcess<mozilla::interceptor::WindowsDllInterceptor<mozilla::interceptor::VMSharingPolicyUnique<mozilla::interceptor::MMPolicyOutOfProcess> >,long (*)(wchar_t *, unsigned long *, _UNICODE_STRING *, void **)>::operator()+0x19 [/builds/worker/workspace/obj-build/dist/include/nsWindowsDllInterceptor.h @ 254] 0a 0000001f`e6ffe360 00007ff9`39bbbb92 firefox!mozilla::freestanding::patched_LdrLoadDll+0x1b3 [/builds/worker/checkouts/gecko/browser/app/winlauncher/freestanding/DllBlocklist.cpp @ 360] 0b 0000001f`e6ffe440 00007ff9`3a51e067 KERNELBASE!LoadLibraryExW+0x172 0c 0000001f`e6ffe4b0 00007ff9`3c4f2c94 user32!_ClientLoadLibrary+0xa7 0d 0000001f`e6ffe650 00007ff9`39f314d4 ntdll!KiUserCallbackDispatcherContinue 0e 0000001f`e6ffe768 00007ff9`3a531bdf win32u!NtUserPeekMessage+0x14 0f 0000001f`e6ffe770 00007ff9`3a531aac user32!_PeekMessage+0x3f 10 0000001f`e6ffe7e0 00007ff8`63d37d4c user32!PeekMessageW+0x9c ... # Child-SP RetAddr Call Site 00 0000001f`e6ffdb98 00007ff6`2bdb0885 0x00000216`7a8c2cb4 (orig_QueryAttributes) 01 0000001f`e6ffdba0 00007ff9`3c47ac39 firefox!TargetNtQueryAttributesFile+0x35 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/filesystem_interception.cc @ 204] 02 0000001f`e6ffdce0 00007ff9`3c47a3f7 ntdll!LdrpGetNtPathFromDosPath+0x95 03 0000001f`e6ffddc0 00007ff9`3c461072 ntdll!LdrpResolveDllName+0x103 04 0000001f`e6ffde30 00007ff9`3c460eaf ntdll!LdrpMapDllFullPath+0x72 05 0000001f`e6ffdfc0 00007ff9`3c4788c4 ntdll!LdrpProcessWork+0x77 06 0000001f`e6ffe010 00007ff9`3c468c9c ntdll!LdrpLoadDllInternal+0x1a0 07 0000001f`e6ffe0b0 00007ff9`3c47a24a ntdll!LdrpLoadDll+0xb0 08 0000001f`e6ffe270 00007ff6`2bd98803 ntdll!LdrLoadDll+0xfa 09 (Inline Function) --------`-------- firefox!mozilla::interceptor::FuncHookCrossProcess<mozilla::interceptor::WindowsDllInterceptor<mozilla::interceptor::VMSharingPolicyUnique<mozilla::interceptor::MMPolicyOutOfProcess> >,long (*)(wchar_t *, unsigned long *, _UNICODE_STRING *, void **)>::operator()+0x19 [/builds/worker/workspace/obj-build/dist/include/nsWindowsDllInterceptor.h @ 254] 0a 0000001f`e6ffe360 00007ff9`39bbbb92 firefox!mozilla::freestanding::patched_LdrLoadDll+0x1b3 [/builds/worker/checkouts/gecko/browser/app/winlauncher/freestanding/DllBlocklist.cpp @ 360] 0b 0000001f`e6ffe440 00007ff9`3a51e067 KERNELBASE!LoadLibraryExW+0x172 0c 0000001f`e6ffe4b0 00007ff9`3c4f2c94 user32!_ClientLoadLibrary+0xa7 0d 0000001f`e6ffe650 00007ff9`39f314d4 ntdll!KiUserCallbackDispatcherContinue 0e 0000001f`e6ffe768 00007ff9`3a531bdf win32u!NtUserPeekMessage+0x14 0f 0000001f`e6ffe770 00007ff9`3a531aac user32!_PeekMessage+0x3f 10 0000001f`e6ffe7e0 00007ff8`63d37d4c user32!PeekMessageW+0x9c ... ``` Now, why do we not have full stacks in the profile for `orig_OpenFile`, `orig_QueryAttributes`, `NtClose`, `NtCreateSection`, `ZwMapViewOfSection`, `ZwQueryVirtualMemory`, `ZwUnmapViewOfSection`? Because they all happen in `LdrLoadDll`, and before calling into `LdrLoadDll` we [disable](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#37) stack walking [over concerns about the function table locks](https://searchfox.org/mozilla-central/source/mozglue/misc/StackWalk.cpp#112-115), and we [restore](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#50) it only after the call. So even though these calls seem to appear out of nowhere in the profile, they should be understood as having the same call stack as what I just shared above. When we understand that, it confirms that the process spends ~100% of its time in `nsThread::ProcessNextEvent`. In fact, we are facing an infinite cycle of events, where the code that we execute to process an event will itself generate a new DLL load event that needs to be processed, and again, leaving the process no time to rest. Here is how the cycle appears: - a first legitimate native event arrives; - we reach `nsThread::ProcessNextEvent` to look for an event; - that calls into `nsBaseAppShell::OnProcessNextEvent`, which calls into `PeekMessageW`; - there is an event, and `pmls64.dll` is not loaded yet, so we reach `_ClientLoadLibrary` to load `pmls64.dll` where the registered hook lives; - that calls `patched_LdrLoadDll`, which will fail to load the DLL, then will call into `DllServices::DispatchDllLoadNotification` to register a new DLL load event for the main thread, without actually posting it for the moment; - since loading the DLL failed, we handle the original event without applying the hook, then we return from `PeekMessageW`; - the next call to `nsThread::ProcessNextEvent` will reach `EnsureMainThreadTasksScheduled`, where the DLL load event will be posted with `PostMessage` as a new legitimate native event, right before going into `nsBaseAppShell::OnProcessNextEvent`, thus starting a new iteration of the cycle... Note that when we only have a cycle because of blocking. If we do not block the DLL, we avoid the cycle: - if the DLL loads successfully, further calls into `PeekMessageW` will not call into `_ClientLoadLibrary` for the same library anymore, they will call the hook directly; - if the DLL fails to load for another reason than blocking (e.g. `DllMain` returns `FALSE` on `DLL_PROCESS_ATTACH`), [we do not generate any DLL load event](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#61-66). The cycle described above exists even when the profiler is not attached.
Thanks Greg and Molly for your comments, they were helpful. Indeed my first comment was incorrect. I managed to reproduce exactly the profile shared in the description, as well as the severe lag. It happens when a DLL that is registered with `SetWindowsHookExW` for `WH_GETMESSAGE` gets blocked by our blocklist. I managed to reproduce the profile by registering my own DLL and blocking it in `about:third-party`, then I realized that the story is a little bit different for `pmls64.dll`... (In reply to Greg Stoll from comment #2) > We have seen issues like this before when we add a DLL that gets loaded by a window hook to the DLL blocklist, and our advice is...[don't block those DLLs](https://firefox-source-docs.mozilla.org/widget/windows/blocklist.html#cases-where-we-should-not-block-a-module), which isn't helpful in this case since we're not doing the blocking. ... In fact [we **are** doing the blocking](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/WindowsDllBlocklistDefs.in#163)! This DLL is hard-blocked in our static blocklist. First let me clarify what we see in the profile now that I understand it better. For a start, the raw addresses ending in 74 and b4 without symbols correspond to the following stacks: ``` # Child-SP RetAddr Call Site 00 0000001f`e6ffdb78 00007ff6`2bdb03d6 0x00000216`7a8c2c74 (orig_OpenFile) 01 0000001f`e6ffdb80 00007ff6`2bdb5125 firefox!TargetNtOpenFile+0x56 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/filesystem_interception.cc @ 125] 02 0000001f`e6ffdcf0 00007ff9`3c46064c firefox!TargetNtOpenFile64+0x35 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/interceptors_64.cc @ 120] 03 0000001f`e6ffdd30 00007ff9`3c4610e0 ntdll!LdrpMapDllNtFileName+0xe8 04 0000001f`e6ffde30 00007ff9`3c460eaf ntdll!LdrpMapDllFullPath+0xe0 05 0000001f`e6ffdfc0 00007ff9`3c4788c4 ntdll!LdrpProcessWork+0x77 06 0000001f`e6ffe010 00007ff9`3c468c9c ntdll!LdrpLoadDllInternal+0x1a0 07 0000001f`e6ffe0b0 00007ff9`3c47a24a ntdll!LdrpLoadDll+0xb0 08 0000001f`e6ffe270 00007ff6`2bd98803 ntdll!LdrLoadDll+0xfa 09 (Inline Function) --------`-------- firefox!mozilla::interceptor::FuncHookCrossProcess<mozilla::interceptor::WindowsDllInterceptor<mozilla::interceptor::VMSharingPolicyUnique<mozilla::interceptor::MMPolicyOutOfProcess> >,long (*)(wchar_t *, unsigned long *, _UNICODE_STRING *, void **)>::operator()+0x19 [/builds/worker/workspace/obj-build/dist/include/nsWindowsDllInterceptor.h @ 254] 0a 0000001f`e6ffe360 00007ff9`39bbbb92 firefox!mozilla::freestanding::patched_LdrLoadDll+0x1b3 [/builds/worker/checkouts/gecko/browser/app/winlauncher/freestanding/DllBlocklist.cpp @ 360] 0b 0000001f`e6ffe440 00007ff9`3a51e067 KERNELBASE!LoadLibraryExW+0x172 0c 0000001f`e6ffe4b0 00007ff9`3c4f2c94 user32!_ClientLoadLibrary+0xa7 0d 0000001f`e6ffe650 00007ff9`39f314d4 ntdll!KiUserCallbackDispatcherContinue 0e 0000001f`e6ffe768 00007ff9`3a531bdf win32u!NtUserPeekMessage+0x14 0f 0000001f`e6ffe770 00007ff9`3a531aac user32!_PeekMessage+0x3f 10 0000001f`e6ffe7e0 00007ff8`63d37d4c user32!PeekMessageW+0x9c ... # Child-SP RetAddr Call Site 00 0000001f`e6ffdb98 00007ff6`2bdb0885 0x00000216`7a8c2cb4 (orig_QueryAttributes) 01 0000001f`e6ffdba0 00007ff9`3c47ac39 firefox!TargetNtQueryAttributesFile+0x35 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/filesystem_interception.cc @ 204] 02 0000001f`e6ffdce0 00007ff9`3c47a3f7 ntdll!LdrpGetNtPathFromDosPath+0x95 03 0000001f`e6ffddc0 00007ff9`3c461072 ntdll!LdrpResolveDllName+0x103 04 0000001f`e6ffde30 00007ff9`3c460eaf ntdll!LdrpMapDllFullPath+0x72 05 0000001f`e6ffdfc0 00007ff9`3c4788c4 ntdll!LdrpProcessWork+0x77 06 0000001f`e6ffe010 00007ff9`3c468c9c ntdll!LdrpLoadDllInternal+0x1a0 07 0000001f`e6ffe0b0 00007ff9`3c47a24a ntdll!LdrpLoadDll+0xb0 08 0000001f`e6ffe270 00007ff6`2bd98803 ntdll!LdrLoadDll+0xfa 09 (Inline Function) --------`-------- firefox!mozilla::interceptor::FuncHookCrossProcess<mozilla::interceptor::WindowsDllInterceptor<mozilla::interceptor::VMSharingPolicyUnique<mozilla::interceptor::MMPolicyOutOfProcess> >,long (*)(wchar_t *, unsigned long *, _UNICODE_STRING *, void **)>::operator()+0x19 [/builds/worker/workspace/obj-build/dist/include/nsWindowsDllInterceptor.h @ 254] 0a 0000001f`e6ffe360 00007ff9`39bbbb92 firefox!mozilla::freestanding::patched_LdrLoadDll+0x1b3 [/builds/worker/checkouts/gecko/browser/app/winlauncher/freestanding/DllBlocklist.cpp @ 360] 0b 0000001f`e6ffe440 00007ff9`3a51e067 KERNELBASE!LoadLibraryExW+0x172 0c 0000001f`e6ffe4b0 00007ff9`3c4f2c94 user32!_ClientLoadLibrary+0xa7 0d 0000001f`e6ffe650 00007ff9`39f314d4 ntdll!KiUserCallbackDispatcherContinue 0e 0000001f`e6ffe768 00007ff9`3a531bdf win32u!NtUserPeekMessage+0x14 0f 0000001f`e6ffe770 00007ff9`3a531aac user32!_PeekMessage+0x3f 10 0000001f`e6ffe7e0 00007ff8`63d37d4c user32!PeekMessageW+0x9c ... ``` Now, why do we not have full stacks in the profile for `orig_OpenFile`, `orig_QueryAttributes`, `NtClose`, `NtCreateSection`, `ZwMapViewOfSection`, `ZwQueryVirtualMemory`, `ZwUnmapViewOfSection`? Because they all happen in `LdrLoadDll`, and before calling into `LdrLoadDll` we [disable](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#37) stack walking [over concerns about the function table locks](https://searchfox.org/mozilla-central/source/mozglue/misc/StackWalk.cpp#112-115), and we [restore](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#50) it only after the call. So even though these calls seem to appear out of nowhere in the profile, they should be understood as having the same call stack as what I just shared above. When we understand that, it confirms that the process spends ~100% of its time in `nsThread::ProcessNextEvent`. In fact, we are facing an infinite cycle of events, where the code that we execute to process an event will itself generate a new DLL load event that needs to be processed, and again, leaving the process no time to rest. Here is how the cycle appears: - a first legitimate native event arrives; - we reach `nsThread::ProcessNextEvent` to look for an event; - that calls into `nsBaseAppShell::OnProcessNextEvent`, which calls into `PeekMessageW`; - there is an event, and `pmls64.dll` is not loaded yet, so we reach `_ClientLoadLibrary` to load `pmls64.dll` where the registered hook lives; - that calls `patched_LdrLoadDll`, which will fail to load the DLL, then will call into `DllServices::DispatchDllLoadNotification` to register a new DLL load event for the main thread, without actually posting it for the moment; - since loading the DLL failed, we handle the original event without applying the hook, then we return from `PeekMessageW`; - the next call to `nsThread::ProcessNextEvent` will reach `EnsureMainThreadTasksScheduled`, where the DLL load event will be posted with `PostMessage` as a new legitimate native event, right before going into `nsBaseAppShell::OnProcessNextEvent`, thus starting a new iteration of the cycle... Note that when we only have a cycle because of blocking. If we do not block the DLL, we avoid the cycle: - if the DLL loads successfully, further calls into `PeekMessageW` will not call into `_ClientLoadLibrary` for the same library anymore, they will call the hook directly; - if the DLL fails to load for another reason than blocking (e.g. `DllMain` returns `FALSE` on `DLL_PROCESS_ATTACH`), [we do not generate any DLL load event](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#61-66). The cycle described above exists even when the profiler is not attached.
Thanks Greg and Molly for your comments, they were helpful. Indeed my first comment was incorrect. I managed to reproduce exactly the profile shared in the description, as well as the severe lag. It happens when a DLL that is registered with `SetWindowsHookExW` for `WH_GETMESSAGE` gets blocked by our blocklist. I managed to reproduce the profile by registering my own DLL and blocking it in `about:third-party`, then I realized that the story is a little bit different for `pmls64.dll`... (In reply to Greg Stoll from comment #2) > We have seen issues like this before when we add a DLL that gets loaded by a window hook to the DLL blocklist, and our advice is...[don't block those DLLs](https://firefox-source-docs.mozilla.org/widget/windows/blocklist.html#cases-where-we-should-not-block-a-module), which isn't helpful in this case since we're not doing the blocking. ... In fact [we **are** doing the blocking](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/WindowsDllBlocklistDefs.in#163)! This DLL is hard-blocked in our static blocklist. First let me clarify what we see in the profile now that I understand it better. For a start, the raw addresses ending in 74 and b4 without symbols correspond to the following stacks: ``` # Child-SP RetAddr Call Site 00 0000001f`e6ffdb78 00007ff6`2bdb03d6 0x00000216`7a8c2c74 (orig_OpenFile) 01 0000001f`e6ffdb80 00007ff6`2bdb5125 firefox!TargetNtOpenFile+0x56 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/filesystem_interception.cc @ 125] 02 0000001f`e6ffdcf0 00007ff9`3c46064c firefox!TargetNtOpenFile64+0x35 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/interceptors_64.cc @ 120] 03 0000001f`e6ffdd30 00007ff9`3c4610e0 ntdll!LdrpMapDllNtFileName+0xe8 04 0000001f`e6ffde30 00007ff9`3c460eaf ntdll!LdrpMapDllFullPath+0xe0 05 0000001f`e6ffdfc0 00007ff9`3c4788c4 ntdll!LdrpProcessWork+0x77 06 0000001f`e6ffe010 00007ff9`3c468c9c ntdll!LdrpLoadDllInternal+0x1a0 07 0000001f`e6ffe0b0 00007ff9`3c47a24a ntdll!LdrpLoadDll+0xb0 08 0000001f`e6ffe270 00007ff6`2bd98803 ntdll!LdrLoadDll+0xfa 09 (Inline Function) --------`-------- firefox!mozilla::interceptor::FuncHookCrossProcess<mozilla::interceptor::WindowsDllInterceptor<mozilla::interceptor::VMSharingPolicyUnique<mozilla::interceptor::MMPolicyOutOfProcess> >,long (*)(wchar_t *, unsigned long *, _UNICODE_STRING *, void **)>::operator()+0x19 [/builds/worker/workspace/obj-build/dist/include/nsWindowsDllInterceptor.h @ 254] 0a 0000001f`e6ffe360 00007ff9`39bbbb92 firefox!mozilla::freestanding::patched_LdrLoadDll+0x1b3 [/builds/worker/checkouts/gecko/browser/app/winlauncher/freestanding/DllBlocklist.cpp @ 360] 0b 0000001f`e6ffe440 00007ff9`3a51e067 KERNELBASE!LoadLibraryExW+0x172 0c 0000001f`e6ffe4b0 00007ff9`3c4f2c94 user32!_ClientLoadLibrary+0xa7 0d 0000001f`e6ffe650 00007ff9`39f314d4 ntdll!KiUserCallbackDispatcherContinue 0e 0000001f`e6ffe768 00007ff9`3a531bdf win32u!NtUserPeekMessage+0x14 0f 0000001f`e6ffe770 00007ff9`3a531aac user32!_PeekMessage+0x3f 10 0000001f`e6ffe7e0 00007ff8`63d37d4c user32!PeekMessageW+0x9c ... # Child-SP RetAddr Call Site 00 0000001f`e6ffdb98 00007ff6`2bdb0885 0x00000216`7a8c2cb4 (orig_QueryAttributes) 01 0000001f`e6ffdba0 00007ff9`3c47ac39 firefox!TargetNtQueryAttributesFile+0x35 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/filesystem_interception.cc @ 204] 02 0000001f`e6ffdce0 00007ff9`3c47a3f7 ntdll!LdrpGetNtPathFromDosPath+0x95 03 0000001f`e6ffddc0 00007ff9`3c461072 ntdll!LdrpResolveDllName+0x103 04 0000001f`e6ffde30 00007ff9`3c460eaf ntdll!LdrpMapDllFullPath+0x72 05 0000001f`e6ffdfc0 00007ff9`3c4788c4 ntdll!LdrpProcessWork+0x77 06 0000001f`e6ffe010 00007ff9`3c468c9c ntdll!LdrpLoadDllInternal+0x1a0 07 0000001f`e6ffe0b0 00007ff9`3c47a24a ntdll!LdrpLoadDll+0xb0 08 0000001f`e6ffe270 00007ff6`2bd98803 ntdll!LdrLoadDll+0xfa 09 (Inline Function) --------`-------- firefox!mozilla::interceptor::FuncHookCrossProcess<mozilla::interceptor::WindowsDllInterceptor<mozilla::interceptor::VMSharingPolicyUnique<mozilla::interceptor::MMPolicyOutOfProcess> >,long (*)(wchar_t *, unsigned long *, _UNICODE_STRING *, void **)>::operator()+0x19 [/builds/worker/workspace/obj-build/dist/include/nsWindowsDllInterceptor.h @ 254] 0a 0000001f`e6ffe360 00007ff9`39bbbb92 firefox!mozilla::freestanding::patched_LdrLoadDll+0x1b3 [/builds/worker/checkouts/gecko/browser/app/winlauncher/freestanding/DllBlocklist.cpp @ 360] 0b 0000001f`e6ffe440 00007ff9`3a51e067 KERNELBASE!LoadLibraryExW+0x172 0c 0000001f`e6ffe4b0 00007ff9`3c4f2c94 user32!_ClientLoadLibrary+0xa7 0d 0000001f`e6ffe650 00007ff9`39f314d4 ntdll!KiUserCallbackDispatcherContinue 0e 0000001f`e6ffe768 00007ff9`3a531bdf win32u!NtUserPeekMessage+0x14 0f 0000001f`e6ffe770 00007ff9`3a531aac user32!_PeekMessage+0x3f 10 0000001f`e6ffe7e0 00007ff8`63d37d4c user32!PeekMessageW+0x9c ... ``` Now, why do we not have full stacks in the profile for `orig_OpenFile`, `orig_QueryAttributes`, `NtClose`, `NtCreateSection`, `ZwMapViewOfSection`, `ZwQueryVirtualMemory`, `ZwUnmapViewOfSection`? Because they all happen in `LdrLoadDll`, and before calling into `LdrLoadDll` we [disable](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#37) stack walking [over concerns about the function table locks](https://searchfox.org/mozilla-central/source/mozglue/misc/StackWalk.cpp#112-115), and we [restore](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#50) it only after the call. So even though these calls seem to appear out of nowhere in the profile, they should be understood as having the same call stack as what I just shared above. When we understand that, it confirms that the process spends ~100% of its time in `nsThread::ProcessNextEvent`. In fact, we are facing an infinite cycle of events, where the code that we execute to process an event will itself generate a new DLL load event that needs to be processed, and again, leaving the process no time to rest. Here is how the cycle appears: - a first legitimate native event arrives; - we reach `nsThread::ProcessNextEvent` to look for an event; - that calls into `nsBaseAppShell::OnProcessNextEvent`, which calls into `PeekMessageW`; - there is an event, and `pmls64.dll` is not loaded yet, so we reach `_ClientLoadLibrary` to load `pmls64.dll` where the registered hook lives; - that calls `patched_LdrLoadDll`, which will fail to load the DLL because it is blocked, then will call into `DllServices::DispatchDllLoadNotification` to register a new DLL load event for the main thread, without actually posting it for the moment; - since loading the DLL failed, we handle the original event without applying the hook, then we return from `PeekMessageW`; - the next call to `nsThread::ProcessNextEvent` will reach `EnsureMainThreadTasksScheduled`, where the DLL load event will be posted with `PostMessage` as a new legitimate native event, right before going into `nsBaseAppShell::OnProcessNextEvent`, thus starting a new iteration of the cycle... Note that when we only have a cycle because of blocking. If we do not block the DLL, we avoid the cycle: - if the DLL loads successfully, further calls into `PeekMessageW` will not call into `_ClientLoadLibrary` for the same library anymore, they will call the hook directly; - if the DLL fails to load for another reason than blocking (e.g. `DllMain` returns `FALSE` on `DLL_PROCESS_ATTACH`), [we do not generate any DLL load event](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#61-66). The cycle described above exists even when the profiler is not attached.
Thanks Greg and Molly for your comments, they were helpful. Indeed my first comment was incorrect. I managed to reproduce exactly the profile shared in the description, as well as the severe lag. It happens when a DLL that is registered with `SetWindowsHookExW` for `WH_GETMESSAGE` gets blocked by our blocklist. I managed to reproduce the profile by registering my own DLL and blocking it in `about:third-party`, then I realized that the story is a little bit different for `pmls64.dll`... (In reply to Greg Stoll from comment #2) > We have seen issues like this before when we add a DLL that gets loaded by a window hook to the DLL blocklist, and our advice is...[don't block those DLLs](https://firefox-source-docs.mozilla.org/widget/windows/blocklist.html#cases-where-we-should-not-block-a-module), which isn't helpful in this case since we're not doing the blocking. ... In fact [we **are** doing the blocking](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/WindowsDllBlocklistDefs.in#163)! This DLL is hard-blocked in our static blocklist. First let me clarify what we see in the profile now that I understand it better. For a start, the raw addresses ending in 74 and b4 without symbols correspond to the following stacks: ``` # Child-SP RetAddr Call Site 00 0000001f`e6ffdb78 00007ff6`2bdb03d6 0x00000216`7a8c2c74 (orig_OpenFile) 01 0000001f`e6ffdb80 00007ff6`2bdb5125 firefox!TargetNtOpenFile+0x56 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/filesystem_interception.cc @ 125] 02 0000001f`e6ffdcf0 00007ff9`3c46064c firefox!TargetNtOpenFile64+0x35 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/interceptors_64.cc @ 120] 03 0000001f`e6ffdd30 00007ff9`3c4610e0 ntdll!LdrpMapDllNtFileName+0xe8 04 0000001f`e6ffde30 00007ff9`3c460eaf ntdll!LdrpMapDllFullPath+0xe0 05 0000001f`e6ffdfc0 00007ff9`3c4788c4 ntdll!LdrpProcessWork+0x77 06 0000001f`e6ffe010 00007ff9`3c468c9c ntdll!LdrpLoadDllInternal+0x1a0 07 0000001f`e6ffe0b0 00007ff9`3c47a24a ntdll!LdrpLoadDll+0xb0 08 0000001f`e6ffe270 00007ff6`2bd98803 ntdll!LdrLoadDll+0xfa 09 (Inline Function) --------`-------- firefox!mozilla::interceptor::FuncHookCrossProcess<mozilla::interceptor::WindowsDllInterceptor<mozilla::interceptor::VMSharingPolicyUnique<mozilla::interceptor::MMPolicyOutOfProcess> >,long (*)(wchar_t *, unsigned long *, _UNICODE_STRING *, void **)>::operator()+0x19 [/builds/worker/workspace/obj-build/dist/include/nsWindowsDllInterceptor.h @ 254] 0a 0000001f`e6ffe360 00007ff9`39bbbb92 firefox!mozilla::freestanding::patched_LdrLoadDll+0x1b3 [/builds/worker/checkouts/gecko/browser/app/winlauncher/freestanding/DllBlocklist.cpp @ 360] 0b 0000001f`e6ffe440 00007ff9`3a51e067 KERNELBASE!LoadLibraryExW+0x172 0c 0000001f`e6ffe4b0 00007ff9`3c4f2c94 user32!_ClientLoadLibrary+0xa7 0d 0000001f`e6ffe650 00007ff9`39f314d4 ntdll!KiUserCallbackDispatcherContinue 0e 0000001f`e6ffe768 00007ff9`3a531bdf win32u!NtUserPeekMessage+0x14 0f 0000001f`e6ffe770 00007ff9`3a531aac user32!_PeekMessage+0x3f 10 0000001f`e6ffe7e0 00007ff8`63d37d4c user32!PeekMessageW+0x9c ... # Child-SP RetAddr Call Site 00 0000001f`e6ffdb98 00007ff6`2bdb0885 0x00000216`7a8c2cb4 (orig_QueryAttributes) 01 0000001f`e6ffdba0 00007ff9`3c47ac39 firefox!TargetNtQueryAttributesFile+0x35 [/builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/filesystem_interception.cc @ 204] 02 0000001f`e6ffdce0 00007ff9`3c47a3f7 ntdll!LdrpGetNtPathFromDosPath+0x95 03 0000001f`e6ffddc0 00007ff9`3c461072 ntdll!LdrpResolveDllName+0x103 04 0000001f`e6ffde30 00007ff9`3c460eaf ntdll!LdrpMapDllFullPath+0x72 05 0000001f`e6ffdfc0 00007ff9`3c4788c4 ntdll!LdrpProcessWork+0x77 06 0000001f`e6ffe010 00007ff9`3c468c9c ntdll!LdrpLoadDllInternal+0x1a0 07 0000001f`e6ffe0b0 00007ff9`3c47a24a ntdll!LdrpLoadDll+0xb0 08 0000001f`e6ffe270 00007ff6`2bd98803 ntdll!LdrLoadDll+0xfa 09 (Inline Function) --------`-------- firefox!mozilla::interceptor::FuncHookCrossProcess<mozilla::interceptor::WindowsDllInterceptor<mozilla::interceptor::VMSharingPolicyUnique<mozilla::interceptor::MMPolicyOutOfProcess> >,long (*)(wchar_t *, unsigned long *, _UNICODE_STRING *, void **)>::operator()+0x19 [/builds/worker/workspace/obj-build/dist/include/nsWindowsDllInterceptor.h @ 254] 0a 0000001f`e6ffe360 00007ff9`39bbbb92 firefox!mozilla::freestanding::patched_LdrLoadDll+0x1b3 [/builds/worker/checkouts/gecko/browser/app/winlauncher/freestanding/DllBlocklist.cpp @ 360] 0b 0000001f`e6ffe440 00007ff9`3a51e067 KERNELBASE!LoadLibraryExW+0x172 0c 0000001f`e6ffe4b0 00007ff9`3c4f2c94 user32!_ClientLoadLibrary+0xa7 0d 0000001f`e6ffe650 00007ff9`39f314d4 ntdll!KiUserCallbackDispatcherContinue 0e 0000001f`e6ffe768 00007ff9`3a531bdf win32u!NtUserPeekMessage+0x14 0f 0000001f`e6ffe770 00007ff9`3a531aac user32!_PeekMessage+0x3f 10 0000001f`e6ffe7e0 00007ff8`63d37d4c user32!PeekMessageW+0x9c ... ``` Now, why do we not have full stacks in the profile for `orig_OpenFile`, `orig_QueryAttributes`, `NtClose`, `NtCreateSection`, `ZwMapViewOfSection`, `ZwQueryVirtualMemory`, `ZwUnmapViewOfSection`? Because they all happen in `LdrLoadDll`, and before calling into `LdrLoadDll` we [disable](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#37) stack walking [over concerns about the function table locks](https://searchfox.org/mozilla-central/source/mozglue/misc/StackWalk.cpp#112-115), and we [restore](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#50) it only after the call. So even though these calls seem to appear out of nowhere in the profile, they should be understood as having the same call stack as what I just shared above. When we understand that, it confirms that the process spends ~100% of its time in `nsThread::ProcessNextEvent`. In fact, we are facing an infinite cycle of events, where the code that we execute to process an event will itself generate a new DLL load event that needs to be processed, and again, leaving the process no time to rest. Here is how the cycle appears: - a first legitimate native event arrives; - we reach `nsThread::ProcessNextEvent` to look for an event; - that calls into `nsBaseAppShell::OnProcessNextEvent`, which calls into `PeekMessageW`; - there is an event, and `pmls64.dll` is not loaded yet, so we reach `_ClientLoadLibrary` to load `pmls64.dll` where the registered hook lives; - that calls `patched_LdrLoadDll`, which will fail to load the DLL because it is blocked, then will call into `DllServices::DispatchDllLoadNotification` to register a new DLL load event for the main thread, without actually posting it for the moment; - since loading the DLL failed, we handle the original event without applying the hook, then we return from `PeekMessageW`; - the next call to `nsThread::ProcessNextEvent` will reach `EnsureMainThreadTasksScheduled`, where the DLL load event will be posted with `PostMessage` as a new legitimate native event, right before going into `nsBaseAppShell::OnProcessNextEvent`, thus starting a new iteration of the cycle... Note that we only have a cycle because of blocking. If we do not block the DLL, we avoid the cycle: - if the DLL loads successfully, further calls into `PeekMessageW` will not call into `_ClientLoadLibrary` for the same library anymore, they will call the hook directly; - if the DLL fails to load for another reason than blocking (e.g. `DllMain` returns `FALSE` on `DLL_PROCESS_ATTACH`), [we do not generate any DLL load event](https://searchfox.org/mozilla-central/source/toolkit/xre/dllservices/mozglue/LoaderObserver.cpp#61-66). The cycle described above exists even when the profiler is not attached.